Spark报错与日志问题查询姿势指南
点击上方蓝色字体,选择“设为星标”
回复”资源“获取更多惊喜
1.1、查看YARN页面的driver日志
可以在右侧搜索框中填对应application号找到任务,然后点击对应的application号链接,如下图所示:
这样会进入该application的信息界面,“FinalStatus”显示了该application的最后状态,点击下方的“logs”按钮也会进入到driver日志界面,如下图所示:
对于driver日志而言,代码中的println()和show()等函数的输出,一般都在stdout里,大部分重要的报错信息都在stderr里。如果application跑的很慢,还可以通过gclog确认是否是因为driver遇到了Full GC,也可以进入stdout或stderr日志界面后,在浏览器地址栏中将“stdout”或“stderr”文字替换为“gclog”,回车后也可查看gclog信息。
在stdout与stderr中,着重搜索和看ERROR、Exception、Failed、Caused by等位置的报错信息,这四个位置都没什么内容再看WARN。
1.2、查看Spark UI
如果任务正在执行中,可以在yarn页面搜对应的application号来找到自己的任务,然后点击右侧的“Application Master”链接进入Spark UI界面,如果任务已完成,该链接会变成“history”,如下图所示:
(1)首先是“Jobs”界面,“Event Timeline”一栏可以显示各Executor的加入与回收;“Active Jobs”一栏指正在运行或等待运行的job;“Description”一列可以看到当前job执行的SQL语句或者代码所在行数,且有链接可点击进入包含的各stages界面;“Submitted”一列表示该job何时被提交给集群;“Duration”一列表示该job持续了多长时间;“Stages”一列显示了该job包含多少个stage,右侧的进度蓝条可以判断总共需要多少个task,完成了多少,同时有多少个task在并发running,如下图所示:
(2)第二个菜单是“Stages”界面,这里包含了所有stage的状态信息,显示的内容和“Jobs”菜单界面中类似,还多了一些内容,例如“Shuffle Read”列表示从上一个stage读取了多少数据量,“Shuffle Write”列表示该stage写入了多少数据量供下一个stage拉取,如下图所示:
如果有失败的stage,也会在“Failure Reason”一列显示出失败原因,如下图所示:
各stage的“Description”处有蓝色链接,可以点击进入该stage的详细信息界面,开头提到了该stage的总执行时长、本地化级别情况、输入数据量(容量/条数)、输出给下一个stage的数据量(容量/条数)、当前执行语句的DAG图等,如下图所示:
可以从DAG看到该stage经过了Hive表扫描、代码生成、shuffle(即Exchange节点)等过程,也指出了对应代码大致所在的行数。下面是metrics表格,包含执行完成的各task持续时间、调度延迟、反序列化时间、GC时间、结果序列化时间、获取结果时间、峰值内存、输入数据量、写出给下一个stage的数据量等,这些metrics信息是可以勾选和隐藏的,如下图所示:
当然该metric表格显示是存在小文件和数据倾斜情况的,后面会详细提到。下面比较重要的是Tasks表格,记录了该stage每一个task的执行情况,包括task id、属于哪次attempt、状态、本地化级别、所属Executor的ID、所在机器IP或域名、启动时间、持续时间、调度延迟等,失败的task也会显示原因,如下图所示:
如果Tasks表格显示的失败原因还是不够详细,想看更完整的日志输出,可以点击“Host”列的stdout或stderr链接查看该task所在Executor的日志。依然是着重搜索和看ERROR、Exception、Failed、Caused by等位置的报错信息,这四个位置都没什么内容再看WARN。
(3)“Storage”菜单在排查任务报错问题时使用的很少,主要是各RDD数据在内存或磁盘中的状态情况。
(4)“Environment”菜单显示了集群与该application的配置信息,如JDK版本、Scala版本、各Spark配置参数值(如driver内存)等。
(5)“Executors”界面显示了Driver与Executor的信息,“Jobs”和“Stages”菜单界面中显示的失败task也会记录在这里,所以也可以从该界面进入各节点的stdout与stderr查看报错日志,如下图所示:
如果在Driver或对应Executor的stdout与stderr中没找到关键报错内容,除了查看GC日志,还可以看该节点的YARN Node Manager日志,点击左侧“Tools”菜单中的“Local logs”链接即可进入,记得提前复制好container号,如下图所示:
在Node Manager日志列表中,每小时都对应一个链接,点击任务出问题的那个小时的链接进去,搜索对应container号查找关于该container的报错信息,可以看到该例子中是因为OOM所以该container被YARN杀死,如下图所示:
(6)如果包含SQL逻辑,顶部会多出来一个“SQL”菜单,里面会有多个job组成的各query信息,可以点击失败query的“Description”列链接,会进入该query的详细DAG图与查询计划界面,也可以点Job ID链接回到对应Jobs菜单界面,如下图所示:
可以看到该query中读写了三个Hive表且显示了读到的数据量,其中两个表进行了shuffle和SortMergJoin,鼠标移动到对应蓝色节点还会显示细节信息如表名、涉及字段、表格式等。
在对应query信息界面的底部,还可以点击“Details”按钮查看该query的逻辑计划与物理计划,读懂这些执行计划需要对编译原理有基本的了解以及具有《SparkSQL内核剖析》涉及的源码理解基础,如下图所示:
(7)如果是Streaming实时任务,还会多出来一个“Streaming”菜单,可以查看各微批次(batch)的延迟等情况,一般常常会看“Scheduling Delay”,这一列如果大多是0ms到2ms左右,说明各批次处理没有明显的延迟,如果ms数较大则可能需要关注前面批次的调度延迟情况,如下图所示:
二、常见问题判断与解决方法
2.1、数据倾斜
在Spark application的执行过程中,会遇到时间很长的情况,其中一个可能性就是数据倾斜,判定数据倾斜的标准之一是上面提到过的“Stages”菜单中,对应stage的Description链接里的metrics表格,如下图所示:
可以看到在“Shuffle Read Size”或“Input Size”那一栏中,各task读取数据量的最小值、中位数、最大值等并不均匀,如果是更加极端的数据倾斜,“Duration”那一栏的最大执行时间也会很长。
数据倾斜的另一个现象是在application运行中,“Executors”菜单里Active状态的executor数量只有个别几个,大部分的executor都已经进入Dead状态,这是因为开启了Dynamic Allocation特性,executor只要空闲(idle)超过60秒就会被资源回收,如下图所示:
此时也可以看到Stages界面中正在执行的stage只有个别task在running,如下图所示:
这样的stage点击“Description”列的蓝色链接进去后,下方的“Tasks”表格中,处在running状态的个别task所读取的数据量(Shuffle Read或Input列)远比其他task大,如下图所示:
当然,数据倾斜有时还会伴随个别task所属的executor内存溢出的现象,如下图所示:
如果的确遇到了数据倾斜,可参考上面博客链接的第11点解决。如果自己集群的Spark版本在3.0以上,或者内部2.x版本合入了Intel的Adaptive Execution特性源码,并且确定造成数据倾斜的代码位置有join操作,则可以加上如下参数缓解:
第二个参数的原理可理解为将部分倾斜的Partition (判断标准为该Partition数据是所有Partition Shuffle Write中位数的N倍) 拿出来单独处理,即原本由一个Task 处理的倾斜Partition数据拆分成多个Task共同join后再union回其他partition的结果中,每个Task需处理的数据量减少,从而缓解了Partition的倾斜,如下图所示:
但是一般不建议使用该参数,因为没有从本质上解决倾斜问题,只是加大了并发度进行缓解,还容易因拆分出来的task数过多而导致driver OOM。
2.2、小文件过多
小文件过多的表现之一是各task读取的数据量远小于一个HDFS block即128M或256M,它也会导致任务执行的效率较低,极端情况甚至会导致HDFS Namenode内存压力大(因为每个HDFS文件在NM内存中的元信息都是150字节左右,过多数量的小文件会给NM维护这么多文件信息带来压力),如下图所示:
另一种判断标准是“Stages”菜单中,某个stage的进度蓝条上task数太多达到好几万的级别,用Input或Shuffle Read量除以task数后,每个task处理的数据量远小于128或256M,如下图所示:
有时小文件多造成的task数过多,会导致driver full gc从而导致Spark UI网页打不开从而看不到Stages情况,因为driver内存有限且负责spark ui的metrics信息状态维护,如下图所示:
在遇到小文件时,如果自己集群的Spark版本在3.0以上,或者内部2.x版本合入了Intel的Adaptive Execution特性源码,可以加上下面的参数来缓解:
如果自己集群的Spark版本不支持上述参数,也可以在SQL的select语句位置加入强制重分区Hint,重分区数即repartition()中的数字根据任务落地的数据量而定,尽量让每个落地文件大小在256M或128M左右,如下所示:
小文件过多也可能导致内存溢出,因为用于读取每一个文件的reader对象,Spark都会在内存中生成一个1M大小的缓冲区,下面截图来自《SparkSQL内核剖析》:
2.3、笛卡尔积/数据量膨胀
依然是“Stages”菜单中,对应stage的Description链接进入后,下方有个各executor对应task运行情况的表格,如果输入的数据量(容量与Records数)远比输出数据量小,再看DAG图里有涉及到join操作,那就说明左右表join的字段中可能有重复值,发生了笛卡尔积/数据量膨胀:
另一个可能迹象的位置是对应stage的Description链接里的metrics表格中,如果shuffle write的记录数远大于shuffle read的记录数,也说明join的字段值可能有重复,交错关联导致数据量膨胀了:
如果确实遇到了该现象导致任务变慢,可以参考第二章开头的博客链接第24点来解决。
2.4、内存溢出(OOM)
如果数据量很大、数据倾斜、并发度不合理、代码逻辑不合理等原因,导致Driver或者Executor的内存不够,就会出现下图所示的OOM错误:
首先要确认是Driver还是Executor端OOM,也就是OOM的报错内容是在哪个节点的stdout或stderr看到的,那就是哪个节点OOM。如果遇到了可以参考第二章开头的博客链接第12点来解决。
如果是driver端OOM或内存压力大,还有一个判断方法是Spark UI页面打开十分缓慢,因为代码的解析、相关对象的序列化、广播变量、Spark UI的进度状态维护都是在driver进行,此时如果查看driver的GC日志,往往可能发生了Full GC。
关于Spark会报OOM的深层原因,下图摘自《SparkSQL内核剖析》:
2.5、YARN队列资源不足
当application跑的比较慢时,除了前面提到的数据倾斜、数据量膨胀、小文件过多等原因,还可能是同一个YARN队列中正在执行的application太多,或某个application不够优化占据过多资源堵塞了其他application。进入yarn UI后,点击左侧的“scheduler”,然后ctrl+f搜索自己的系统队列,如下图所示:
如果自己队列显示为黄色、或已使用的资源中,内存或CPU核数其中一项已经达到最小资源阈值(Min Resource)、或最小资源非常小,说明自己队列中当前时刻的资源不足,可以点击左上角的RUNNING进入正运行的application界面,在右边的search框中搜索自己队列名然后回车,看看正在运行的各application里“Allocated CPU vcores”和“Allocated Memory MB”这两列,哪个任务有点大,还可以从“name”列看到任务名,与伙伴确认可以被杀掉的application,杀死后释放资源并让任务责任人优化代码与调参,如下图所示:
第二种迹象是,driver的stderr等日志中有如下的未申请到资源的内容:
第三种迹象,如果spark ui的job或stages界面中,正在运行的job或stage只有少数task在长时间running,并且进入该stage的description链接后,观察Metrics与Tasks表格并未发现有某个task数据量巨大的数据倾斜现象,说明暂时申请不到更多的executor来更高并发的运行多个task,如下图所示:
第四种迹象,如果发现任务本身长时间没有实际执行起来,在application的详情界面中看到下图中Node列没有指定IP或域名的现象,说明此时没有启动Application Master,大概率也是yarn队列没资源了:
提交Spark作业 | 科学设定spark-submit参数